| tsung param | 说明 |
|---|---|
| user | 每秒产生的用户数 |
| duration | 持续时间 |
| max_user | 最大用户数 |
| loop | 每个用户循环请求次数 |
| thinktime | 两次请求之间的间隔时间 |
| api | 测试的api接口 |
测试目的:找出play的最大负载能力,进而找出性能瓶颈
| param | value |
|---|---|
| user | 200 |
| duration | 300s |
| max_user | 100000 |
| loop | 600 |
| thinktime | 1s |
| api | /v2/stest5 |
最大并发请求数达到了6000次每秒,260s以后,曲线走势很乱,后来总结出来当并发请求数波动幅度很大时应该是远远超出了此api的承受能力,但这是否可以说这个api的最大负载能力是6000次每秒?这还要结合响应时间图
响应时间在260s之前,大部分都在1s以内,260s之后,急剧攀升,最大达到了12s,此时的并发请求数约为50000,而响应数仅有每秒5000个,若以响应时间小于1s为标准,那么这个api的最大负载能力应该是在5000。每秒5000个并发请求是多还是少?260s之后的响应时间为什么变长?性能瓶颈在哪里?tsung发送的请求数远远超过play的响应数,这些多出来的请求都去哪里了?
从最初测试开始很长一段时间都是这样,无法确定play的最大负载能力,也不能指导程序在性能上的改进,唯一有用的可能是找到了使用nginx负载多play的时候会出现502问题。综合来说,我们缺少一种系统化的压力测试手段,通过它可以一步一步的找出play的最大负载,也应该可以解释响应时间变长的问题,指导性能优化的方向。
最初选择jmeter是因为tsung每隔10s统计一次上一个10s内的每秒并发请求数和平均响应时间,10s对于压力测试来说太长了,若按每秒200个用户来看,10s就产生了2000个用户,或许问题就出在这10s内,google压力测试工具,jmeter相关的结果很多,教程也很多,文档齐全,最重要的是它可以记录每次请求的明细,包括请求发出的绝对时间、响应时间、返回码、是否成功、字节等,看起来很完备。jmeter是java编写的,产生不了tsung那么大的压力,在给它分配1G内存的时候,并发数达到1000的时候就不能稳定输出压力了,自己也开始做在gc。
jmeter不同于tsung,它可以配置总用户数(total_user)和在多长时间内产生这么多用户(ramptime),jmeter会根据这两个数字计算每秒应该产生多少用户,如下配置就是每秒产生30个用户——3000 / 100
| param | value |
|---|---|
| total_user | 3000 |
| ramptime | 100 |
| thinktime | 10ms |
| loop | 100 |
| api | /v2/locations/checkin |
这个曲线很奇怪,一个波峰接一个波峰,考虑到tsung是每10s统计一次,或许tsung也存在这个问题,只是把这些波动平均了,曲线显得平滑很多,推测可能是jmeter自己在做gc,后来对比tsung的测试结果,证实了这个推论。
平均响应时间也很长,基本都在4秒也上,波动范围很大,看不出有用的信息。这次测试说明jmeter产生的压力远不如tsung,但也有可能play根本不需要那么大的压力就可以达到极限。
在纠结jmeter和tsung孰优孰劣的泥潭中时,偶得一神图,这幅图的意思是一个系统随着并发用户数的增多,大致可以分为三个阶段:
这个模型具有指导性的意义,一直以为我们期望找到play的最大负载能力,希望通过调整使play和服务器达到最优,但什么是最优?这个并没有标准,4000的并发是大还是小?根据这幅图的指导,我们的系统也应该有这样一张图,展示并发数与服务器资源和吞吐量的关系,有了这三个区域就可以准确的说出play的最大负载能力是多少,达到什么样的并发数必需做扩展。
压力测试的同时还要采集服务器的资源消耗情况,继续对jmeter的研究,发现了一个jmeter的插件:JMeterPluginsCMD,它可以与jmeter结合使用,在压力测试期间采集服务器的cpu使用率、内存、jvm堆变化、gc时间等参数,或许响应时间变长是因为服务器的cpu已经满负荷?内存已经接近最大?jvm在做频繁的gc?
| param | value |
|---|---|
| total_user | 3000 |
| ramptime | 100 |
| thinktime | 10000ms |
| loop | 50 |
| api | /v2/stest5 |
一开始不知道哪些参数有用,所以从cpu使用率,到磁盘I/O都监控了,看起来有点乱。图中比较重要的是蓝色的线,代表jvm的gc回收情况,高度是本次gc耗时,间隔越短说明gc越频繁,深红色的线是jvm heap,每次gc都会导致heap的波动。gc的效果从两方面看,一是耗时,二是heap的降幅,这幅图中heap随着gc的进行,在小范围内均匀的波动。后面会有导常的情况举例。
注意thinktime是10s,这条曲线堪称完美,第一次得到如此清晰的并发请求曲线,100s的时候达到最大并发数300,之后一直在300上下波动,受jmeter自己的gc的影响,曲线波动幅度稍大,整个曲线大体上左右对称。在前100s内并发请求数的增长以台阶的形式稳定爬升,每级台阶的高度是30——每秒新增用户数,宽度是10s——thinktime,100s后到达平衡区,压力稳定在300上下,500s的时候第一批产生的30个用户的50次请求已经全部完成,每隔10s就有一批用户消失,直到最终压力测试完成。
响应时间绝大多数都是50ms以内,最高点也不过450ms。也就是这个api在这样的压力(300tps)下持续运行10分钟,完全无压力。
结合服务器资源图可以看出在并发数为300的时候服务器资源利率并不高,其中cpu利用率才30%,gc回收也不频繁。在这之后的测试也都朝着这个方向走。
jmeter可以非常方便的采集服务器数据,但产生的压力不够大;而tsung轻而易举的产生非常大的压力,但对服务器数据的采集不是很善长。经过讨论决定同时使用jmeter和tsung,使用tsung产生压力的同时用jmeter采集服务器数据。
| param | value |
|---|---|
| user | 40 |
| duration | 500s |
| max_user | 10000 |
| loop | 500 |
| thinktime | 1s |
| api | /v2/stest5 |
总结使用jmeter测试时得到的对称曲线发现每秒产生的用户数不能太大,duration与thinktime/loop之间是有关系的,如果duration=500s,thinktime=1s,那么要保证所有的用户都产生完的时候,也就是500s的时候,第一批产生的用户还没有消失,所以此时的loop应大于等于500,用公式描述:
loop * thinktime >= duration
对称的曲线分为三部分,上升区,平稳区,下降区,其中上升区的持续时间即为duration,平稳区的持续时间是 loop * thinktime - duration;下降区是第一批产生的用户的所有请求已经成,用户数开始减少。 具体参见孙明欣写的文档
受限于max_user,最大用户数止于10000,在250秒的时候到达10000,此时的服务器每秒响应数为7000,此后一直在7000左右小幅波动。
比较tsung产生的用户和响应的用户可以发现,在660s的时候第一幅图已经开始向了,即第一批产生的用户已经消失了,但是第二幅图中直到730s的时候才有明显的下降,这说明过多请求在play里排队。
尽管施加了高达10000的并发,此时的play处理极限只有7000,但是用户的平均响应时间却出乎意料,最高也才500ms。
这次测试确定了性能测试的基准,/v2/stest5这个api什么都没做,只是简单的返回ok,没有redis,mongodb,mysql等操作,这里只有play,所以基本可以猜测单台play在目前idc的环境下最大的负载能力是7000tps。后来有一次测试/v2/location/checkin时不小心把请求参数填错了,返回结果全是401,得到的曲线与stest5类似,这两种情况下play所做的事情都很少,证实了上述猜测。
虽然确定了play的最大负载能力,但参考理发店模型,我们相当于只找出了第一条分隔线,确定了light load和heavy load,且此时的服务器资源(cpu)并没有达到最高,后来的测试虽然给play施加了更大的压力,但是用户响应时间依然没有显著变长。此事暂且放在一边,接着测真实的api,看看真实的api与stest5有多大的差别
| param | value |
|---|---|
| user | 10 |
| duration | 200s |
| max_user | 10000 |
| loop | 300 |
| thinktime | 1s |
| api | /v2/locations/checkin |
100s的时候并发用户数达到1000,此时每秒响应数曲线开始变形,系统进入heavy load区
400s的时候每秒并发响应数达到最高1400
响应时间都在800ms以下,比较奇怪的是100s的时候并发数是1000,响应时间反而比400s的时候还要长,对比服务器性能指标图,发现100s的时候服务器cpu使用率突然增长,回落后再匀速上升,而此时的gc和heap未见异常,其后又测试了几次,均未重现,考虑到测试时牵涉到其它正在使用的组件,这个异常可以忽略。
由此可以确定对于locations/checkin接口来说,其最大负载能力是1400,当并发请求数到达1000的时候,系统就进入了heavy load区。
下面测试sharing.index,主要是对mongodb进行了读操作
| param | value |
|---|---|
| user | 5 |
| duration | 100s |
| max_user | 10000 |
| loop | 150 |
| thinktime | 1s |
| api | /v2/users/10000025/sharings?dId=35513605339286910683F9028B1&offset=0&limit=65535&filter=proj1 |
加的压力很小,最高才每秒500个并发
30s的时候曲线已经变形,而此时的压力不过150,此后的走势完全凌乱
响应时间在30s以后一直在1s以上,最高更是达到了12s
cpu使用率达到近800%,heap的大小几乎不随gc变化,说明每次gc只回收了一点点垃圾,且全部是full gc
此时上被测的服务器上查看jvm情况,首先使用 jstat -gc 命令查看jvm各代的使用情况和gc情况,发现2G的tenured generation已经接近上限,gc没有继续进行,整个jvm处于瘫痪状态。(忘了截图了)
再使用 jmap -dump:format=b,file=/tmp/heap.hprof pid 把当前的jvm堆导出,有3G大,不过使用gzip压缩后只有400M,拉到本地使用MAT离线分析
上图MAT诊断出了两个问题,heap中存在两个超大的对象,一个814M,一个511M
MAT认为有2个问题,第一个对象是java.util.HashMap类型的,它被system class loader加载,占据了31%的heap内存,被akka.dispatch.xxx application-xxx-dispatcher-2线程所持有;第二个问题信息较少,暂且略过。
点击“Details >>”可以看到问题的明细,这个是当前有问题的对象到gc根的最短路径,这里gc根就是线程dispatcher-2,可以看到这个hashmap的浅引用大小是56byte深引用是536M
关于Shallow heap和Retained heap,参见MAT使用教程
hashmap里有很多的java.util.HashMap$Entry对象
这样的java.util.HashMap$Entry对象有46,539个,还有当前的线程概要信息
这个是当前的线程调用栈,其中的 at models.SharingStat.getCount()和at models.BaseModel.getCount()是我们自己的代码,再住上就进入了mongodb的驱动morphia里了,最终停留在java.util.hashMap.put()这里。
在“Problem Suspect 1 detail”图中,最上边的java.util.HashMap$Entry上点击鼠标左键,选择“List objects” ==>“with outgoing references”可以看到它引用的对象,见下图
注意看红框中字,这说明这个对象下引用了102,641个对象,每个对象大小是10,448byte。
很明显出现了内存泄露,把morphia的源码down下来,根据前边的线程调用情况,跟踪查看函数调用情况,最终发现问题出来我们的models.BaseModel.getCount()中有一行,
// cls is orm class,e.g. SharingStat/HotUser
BasicDAO<T, String> dao = dao(cls, ds);
每调用一次getCount()都会new一个com.google.code.morphia.dao.BaseDao,然后放到morphia中的一个hashmap中,里存储的是cls类的结构(通过反射取得),这个hashmap是全局变量,不会被gc回收,所以每次gc后heap的变化很小,jvm最后无gc,但cpu使用率还是800%,应该是这个hashmap在做resize(),hashmap不断的增大,resize()也一直继续,直到把服务器资源耗尽。
把这个BasicDAO改成全局静态变量,只有play启动的时候初始化一次即可 下面是调整代码后的测试
| param | value |
|---|---|
| user | 5 |
| duration | 300s |
| max_user | 5000 |
| loop | 400 |
| thinktime | 1s |
| api | /v2/users/10000025/sharings?dId=35513605339286910683F9028B1&offset=0&limit=10&filter=proj1 |
与locations/checkin类似,此api的最大负载是950,heavy load区的响应时间接近1s,稍慢,还有优化空间。